Lambdaのログ出力にオススメしたいPythonのライブラリLambda Powertools

Lambda Powertoolsを使うとJSON形式のログ出力が簡単！！

#Python

#サーバーレス

#AWS Lambda

#AWS

岩田智哉

2020.01.05

この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。

CX事業本部@大阪の岩田です。

皆さんはLambda Functionからログを出力する際に、どんな形式でログを出力していますか？後々CloudWatch Logs Insightsで分析することを考えると、やはりログはJSON形式で出力しておきたいところです。出力する項目に関して考えると、リクエストIDなんかは必須と言えるのではないでしょうか？今回紹介するLambda Powertoolsを使うと、このあたりのログ戦略が簡素化できるので良ければお試し下さい。

環境

今回利用した環境です

ランタイム: Python3.8
Lambda Powertools: 0.3.0
AWS Lambda Logging:0.1.1

Lambda Powertoolsとは？

Python3.6以上で利用できるAWS Lambda用のユーティリティライブラリです。

構造化ログ(JSONログ)を出力するためのユーティリティ
X-Rayのトレースを容易にするユーティリティ
SAR-async-lambda-metricsによる非同期でのカスタムメトリクス作成を支援するユーティリティ

が利用可能です。ログ出力に関しては内部的にAWS Lambda Loggingを利用しており、今回試したバージョンでは自力でAWS Lambda Loggingを導入しておかないと正常に動作しませんでした。※issueも上がってました。

なお、こちらのライブラリですが現段階でベータ版です。今後破壊的な変更が入る可能性が高いので、本番利用の際は十分ご注意下さい。

やってみる

実際にやってみましょう。まずはLambdaからaws-lambda-powertoolsとaws-lambda-loggingを利用するためにレイヤーを作成します。レイヤーを作成する詳細な手順は割愛するので、分からなければこちらのブログを参考にして下さい。

AWS LambdaにLayerなるものが追加されたのでPythonで簡単に使ってみる #reinvent

準備ができたら早速ログ出力を試してみます。

import os
from aws_lambda_powertools.logging import logger_setup, logger_inject_lambda_context


os.environ['POWERTOOLS_SERVICE_NAME'] = 'sample_service'
logger = logger_setup()  

@logger_inject_lambda_context
def handler(event, context):

  logger.info({
    'key1': 'val1',
    'key2': 'val2',
    'key3': 'val3',
  })
  
  return

ポイントはlogger_setup()とhandlerに付与している@logger_inject_lambda_contextのデコレータです。logger_setup()でログフォーマットをJSONに変更しつつ、@logger_inject_lambda_contextのデコレータがLambdaのコンテキスト情報から諸々の情報をログに自動付与してくれます。環境変数のPOWERTOOLS_SERVICE_NAMEは必須ではありませんが、この環境変数をセットしておくと出力されるログのserviceに反映されるようになります。今回は分かりやすいようにソースコードからセットしましたが、本来はSAMテンプレート等を介してLambdaの設定から設定するのが良いでしょう。もしくはlogger_setup(service='sample_service')のようにlogger_setupの引数で指定することも可能です。

ソースコードの準備ができたらテストイベントからLambdaを実行し、Cloud Watch Logsに出力されたログを確認してみましょう。

{
    "timestamp": "2020-01-05 07:52:02,789",
    "level": "INFO",
    "location": "sample_service.handler:9",
    "service": "sample_service",
    "cold_start": "true",
    "function_name": "logging_test",
    "function_memory_size": "128",
    "function_arn": "arn:aws:lambda:ap-northeast-1:123456789012:function:logging_test",
    "function_request_id": "41898e79-0075-4b3a-8718-1b3d5d69b1ae",
    "message": {
        "key1": "val1",
        "key2": "val2",
        "key3": "val3"
    }
}

バッチリJSON形式のログが出力されています。他にもコールドスタートかどうかを表すcold_startという項目や、どのバージョン(エイリアス)のLambdaが出力したログか確認するのに使えそうなfunction_arnといった項目も出力されています。これでCloudWatch Logs Insightsを使った調査が捗りそうです。

ログに項目を追加してみる

先程出力されたログには必要そうな情報が色々と自動付与されていますが、システムの要件次第ではさらに項目を追加で出力したいこともあるでしょう。例えばCognitoユーザープールオーソライザーでアクセス制限をかけたAPI GWからLambdaを起動する場合はCognitoユーザープールのsubをログに出力したい場面がありそうです。他にはX-RayのトレースIDなんかも出力しておくと、有事の調査に役立ちそうです。今度は自分でログに出力する項目を変更してみましょう。

import os
from aws_lambda_powertools.logging import logger_setup, logger_inject_lambda_context


os.environ['POWERTOOLS_SERVICE_NAME'] = 'sample_service'
logger = logger_setup(
  attr1='attr1',
  attr2='attr2',
  attr3='attr3',
  )  

def handler(event, context):

  logger.info({
    'key1': 'val1',
    'key2': 'val2',
    'key3': 'val3',
  })
  
  return

ログに出力する項目はlogger_setupの名前付き引数を利用することで制御が可能です。この例では、attr1~attr3という項目をログフォーマットに追加しています。先程使用した@logger_inject_lambda_contextのデコレータも内部的にはLambdaのコンテキスト情報を使ってlogger_setupを呼び出すことでログフォーマットを調整しています。

再度テストイベントを実装し、Cloud Watch Logsに出力されたログを確認してみましょう。

{
    "timestamp": "2020-01-05 07:53:44,941",
    "level": "INFO",
    "location": "sample_service.handler:14",
    "service": "sample_service",
    "attr1": "attr1",
    "attr2": "attr2",
    "attr3": "attr3",
    "message": {
        "key1": "val1",
        "key2": "val2",
        "key3": "val3"
    }
}

これでログのカスタマイズもバッチリですね！

例外が発生した際のログ出力

今度は例外が発生した際のログ出力を確認してみましょう。以下のコードで意図的に例外を発生させ、logger.exception(e)でエラーログを出力してみます。

import os
from aws_lambda_powertools.logging import logger_setup, logger_inject_lambda_context


os.environ['POWERTOOLS_SERVICE_NAME'] = 'sample_service'
logger = logger_setup()  

@logger_inject_lambda_context
def handler(event, context):

  try:
    1 / 0
  except Exception as e:
    logger.exception(e)
    raise e
  
  
  return

テストイベントの実行結果です。

{
    "timestamp": "2020-01-05 07:54:54,909",
    "level": "ERROR",
    "location": "sample_service.handler:14",
    "service": "sample_service",
    "cold_start": "true",
    "function_name": "logging_test",
    "function_memory_size": "128",
    "function_arn": "arn:aws:lambda:ap-northeast-1:123456789012:function:logging_test",
    "function_request_id": "0ed6a4b9-a5d0-48bd-b94f-94185686cdaa",
    "message": "division by zero",
    "exception": "Traceback (most recent call last):\n  File \"/var/task/lambda_function.py\", line 12, in handler\n    1 / 0\nZeroDivisionError: division by zero"
}

出力されたログにexceptionという項目が追加されており、この項目を参照することでスタックトレースが確認できます。これで例外発生時の調査もバッチリですね。